Details
-
Bug
-
Resolution: Fixed
-
Critical
-
0.9.11
-
None
-
Windows XP
Sun JDK 1.5.0_15
Logback 0.9.11
Description
In a multithreaded environment a request of a logger instance can led to a deadlock, when another thread tries to apply a new configuration.
In GenericConfigurator.doConfigure(InputSource):97 a lock is set on a Context instance. Then the new configuration will be applied. During this, a lock on the logger is required. When now a new logger instance is requested by LoggerFactory, LoggerContext.getLogger(String) is called. The operation sets a lock on the root logger to create a new child logger. At the end the method LoggerContext.incSize() is called to increase the number of entries in the loggerCache. This method is declared as "synchronized" and needs a lock on LoggerContext.
Requesting a new logger instance while starting a reconfiguration of logback leds to a deadlock. LoggerContext.incSize() waits for a lock of the context (which is locked by GenericConfigurator), while waiting for lock of logger in Logger.setLevel() - which is locked by LoggerContext.
For further information, see the thread dump:
ManagedService Update Queue@5, priority=5, in group 'main', status: 'MONITOR'
blocks Start Level Event Dispatcher@6
waiting for Start Level Event Dispatcher@6
at ch.qos.logback.classic.Logger.setLevel(Logger.java:188)
at ch.qos.logback.classic.joran.action.LoggerAction.begin(LoggerAction.java:63)
at ch.qos.logback.core.joran.spi.Interpreter.callBeginAction(Interpreter.java:262)
at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:136)
at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:118)
at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:36)
at ch.qos.logback.core.joran.spi.Interpreter.play(Interpreter.java:321)
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:98)
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:74)
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:55)
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:48)
Start Level Event Dispatcher@6 daemon, priority=5, in group 'main', status: 'MONITOR'
blocks ManagedService Update Queue@5
waiting for ManagedService Update Queue@5
at ch.qos.logback.classic.LoggerContext.incSize(LoggerContext.java:153)
at ch.qos.logback.classic.LoggerContext.getLogger(LoggerContext.java:142)
at ch.qos.logback.classic.LoggerContext.getLogger(LoggerContext.java:46)
at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:161)
at org.slf4j.bridge.SLF4JBridgeHandler.getSLF4JLogger(SLF4JBridgeHandler.java:149)
at org.slf4j.bridge.SLF4JBridgeHandler.publish(SLF4JBridgeHandler.java:234)
at java.util.logging.Logger.log(Logger.java:452)
at java.util.logging.Logger.doLog(Logger.java:474)
at java.util.logging.Logger.log(Logger.java:497)
at java.util.logging.Logger.info(Logger.java:1.016)
A quick fix is to set a lock on the LoggerContext in LoggerContext.getLogger(String). I am not sure, if this is the best solution, but it seems to work.